Java诊断工具

发表于 | 分类于

Foreword

解决问题的前提是定位问题. 在掌握这些工具之后, 才发现之前排查问题的方式简直是隔靴搔痒. 为了区别系统级的命令, 把本章取名为”Java诊断工具”.

Greys Anatomy

一次在排查代码运行性能过程中, 尝试编写一个BTrace脚本来跟踪VM栈每一步调用的耗时(期望效果类似Pinpoint的调用跟踪), 然而这个脚本憋了半天也没写出来. 终于遇到了阿里的Greys Anatomy - Github, 不禁惊叹这个工具真是太方便了, 只要三步:

1
2
3
jps -ml // 确定进程ID
./greys.sh $PID
> trace $类名 $方法名

这个项目的文档非常全面而且是中文, 可以直接点击上面的链接深入了解.

JVM自带工具

本章的内容基于JDK8, 不同版本输出的内容有些差别. 相关内容在Java Platform, Standard Edition Tools Reference for Oracle JDK on Solaris, Linux, and OS X, Release 8写的很详细.

  • JDK基本工具类位于$JAVA_HOME/bin.
  • 这些工具类的实现基于tools.jar, 它不是Java标准API, HotSpot提供的. 所以能开箱即用的只有HotSpot虚拟机.
  • 部分JDK小工具参考了UNIX命名方式, 如 jps和ps功能类似.
  • 如果对命令的选项不清楚, 直接执行 命令名 -help即可查询.

1. jps

列出正在运行的虚拟机进程. jps [options] [hostid]

  • -m : 输出传递给main函数的参数
  • -l : 输出主类的全名/jar包路径
  • -v : 输出JVM参数

2. jstat

这个命令功能比较多, 根据选项可以对一个JVM进程某个特定指标进行查询. 这里展示的结果项非常多,

比如查看GC情况

1
2
3
4
jstac -gc 5234 // 查看进程好5234的GC情况

 S0C    S1C    S0U    S1U      EC       EU        OC         OU       MC     MU    CCSC   CCSU   YGC     YGCT    FGC    FGCT     GCT
61440.0 61440.0 10961.4  0.0   491520.0 10220.7   204800.0   32791.2   62688.0 61132.7 7412.0 7099.1     10    1.826   4      0.261    2.087

观察结果, 截止到CCSU之前都可用下面两条组合解释:

  • S0, S1表示新生代中的两个Survivor区域. E表示Eden. O表示Old Gen. M表示MetaSpace. CCS表示压缩类空间(Compressed Class Space), 它是MetaSpace的一部分.
  • C即Capacity, 表示容量. U为USED, 表示已用多少. 单位都是KB.

CCSU后面的含义如下;

  • YGC : 年轻代GC次数
  • YGCT : 年轻代GC时间
  • FGC : 年老代GC次数
  • FGCT : 年老带GC时间
  • GCT : GC消耗总时间

jstat的基本格式为: jstat [option vmid [interval[s|ms]] [count]].

刚刚的option是-gc. interval和count分别表示: 每隔interval执行一次, 共执行count次后结束. jstat -gc 5234 2s 3, 即没两秒执行一次, 执行3次后结束. 除了-gc之外还支持:

-class

1
2
3
stat -class 5234
Loaded  Bytes  Unloaded  Bytes     Time
 10751 20031.0        0     0.0      15.25

依次表示 加载的类数量, 字节数, 卸载的类数量, 卸载的类字节数. 加载类耗费的时间.

-complier

1
2
3
jstat -compiler 5234
Compiled Failed Invalid   Time   FailedType FailedMethod
    9198      2       0    79.12          1 sun/misc/URLClassPath getNextLoader

-printcompilation

1
2
3
jstat -printcompilation 5234
Compiled  Size  Type Method
    9198     57    1 com/netflix/servo/monitor/Monitors isNumericType

其他GC相关

-gccapacity
1
2
3
jstat -gccapacity 5234
 NGCMN    NGCMX     NGC     S0C   S1C       EC      OGCMN      OGCMX       OGC         OC       MCMN     MCMX      MC     CCSMN    CCSMX     CCSC    YGC    FGC
614400.0 614400.0 614400.0 61440.0 61440.0 491520.0   204800.0   204800.0   204800.0   204800.0      0.0 1103872.0  62688.0      0.0 1048576.0   7412.0     10     4

观察后缀, 主要多了MN, MX, 同样指的是Capacity,分别表示最小, 最大.

-gcutil
1
2
3
jstat -gcutil 5234
  S0     S1     E      O      M     CCS    YGC     YGCT    FGC    FGCT     GCT
 17.84   0.00   9.50  16.01  97.52  95.78     10    1.826     4    0.261    2.087

以百分比格式输出占用量.

-gcnew, -gcold, -gcnewcapacity, -gcoldcapacity

功能应该可以猜到了.

1
2
3
4
5
6
7
jstat -gcold 5234
   MC       MU      CCSC     CCSU       OC          OU       YGC    FGC    FGCT     GCT
 62688.0  61132.7   7412.0   7099.1    204800.0     32791.2     10     4    0.261    2.087

jstat -gcnew 5234
 S0C    S1C    S0U    S1U   TT MTT  DSS      EC       EU     YGC     YGCT
61440.0 61440.0 10961.4    0.0  6   6 30720.0 491520.0  46711.6     10    1.826

这里有点奇怪的是, 为什么MetaSpace归属到Old Gen的统计中了? 另外年轻代有三个之前没有看过的指标: TT, MTT, DSS

TT: Tenuring threshold.
MTT: Maximum tenuring threshold.
DSS: Desired survivor size (kB).

-gccause
1
2
3
jstat -gccause 5234
  S0     S1     E      O      M     CCS    YGC     YGCT    FGC    FGCT     GCT    LGCC                 GCC
 17.84   0.00  16.91  16.01  97.52  95.78     10    1.826     4    0.261    2.087 Allocation Failure   No GC

同样以百分比输出, 多了个LGCC, 即 Last GC Cause. GCC, 表示当前GC原因.

3. jinfo

查看参数信息和System Properties. 其中有很多重要信息, 包括一些默认的JVM参数. 除次之外很多框架都将属性System.setProperties, 可以直接通过此命令查看.

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
48
49
50
51
52
53
54
55
56
57
58
59
60
61
62
63
64
65
66
67
68
69
70
71
72
jinfo 5234

Attaching to process ID 5234, please wait...
Debugger attached successfully.
Server compiler detected.
JVM version is 25.121-b13
Java System Properties:

java.runtime.name = Java(TM) SE Runtime Environment
sun.rmi.transport.tcp.responseTimeout = 8000
java.vm.version = 25.121-b13
sun.boot.library.path = /usr/local/jdk1.8.0_121/jre/lib/amd64
java.vendor.url = http://java.oracle.com/
java.vm.vendor = Oracle Corporation
path.separator = :
file.encoding.pkg = sun.io
java.vm.name = Java HotSpot(TM) 64-Bit Server VM
sun.os.patch.level = unknown
sun.java.launcher = SUN_STANDARD
user.country = US
user.dir = /data/dubbo/test-project/jiangnenghua
java.vm.specification.name = Java Virtual Machine Specification
PID = 5234
java.runtime.version = 1.8.0_121-b13
java.awt.graphicsenv = sun.awt.X11GraphicsEnvironment
os.arch = amd64
java.endorsed.dirs = /usr/local/jdk1.8.0_121/jre/lib/endorsed
org.jboss.logging.provider = slf4j
line.separator =

java.io.tmpdir = /tmp
java.vm.specification.vendor = Oracle Corporation
os.name = Linux
sun.jnu.encoding = UTF-8
java.library.path = /usr/java/packages/lib/amd64:/usr/lib64:/lib64:/lib:/usr/lib
spring.beaninfo.ignore = true
sun.nio.ch.bugLevel =
java.specification.name = Java Platform API Specification
java.class.version = 52.0
sun.management.compiler = HotSpot 64-Bit Tiered Compilers
os.version = 3.10.0-693.2.2.el7.x86_64
user.home = /home/publish
user.timezone = Asia/Shanghai
java.awt.printerjob = sun.print.PSPrinterJob
file.encoding = UTF-8
@appId = test-project
java.specification.version = 1.8
header.errorCode = true
user.name = publish
java.class.path = test-project.jar
java.vm.specification.version = 1.8
sun.arch.data.model = 64
sun.java.command = test-project.jar
java.home = /usr/local/jdk1.8.0_121/jre
user.language = en
java.specification.vendor = Oracle Corporation
awt.toolkit = sun.awt.X11.XToolkit
java.vm.info = mixed mode
java.version = 1.8.0_121
java.ext.dirs = /usr/local/jdk1.8.0_121/jre/lib/ext:/usr/java/packages/lib/ext
sun.boot.class.path = /usr/local/jdk1.8.0_121/jre/lib/resources.jar:/usr/local/jdk1.8.0_121/jre/lib/rt.jar:/usr/local/jdk1.8.0_121/jre/lib/sunrsasign.jar:/usr/local/jdk1.8.0_121/jre/lib/jsse.jar:/usr/local/jdk1.8.0_121/jre/lib/jce.jar:/usr/local/jdk1.8.0_121/jre/lib/charsets.jar:/usr/local/jdk1.8.0_121/jre/lib/jfr.jar:/usr/local/jdk1.8.0_121/jre/classes
java.awt.headless = true
java.vendor = Oracle Corporation
file.separator = /
java.vendor.url.bug = http://bugreport.sun.com/bugreport/
sun.io.unicode.encoding = UnicodeLittle
sun.cpu.endian = little
sun.cpu.isalist =

VM Flags:
Non-default VM flags: -XX:CICompilerCount=3 -XX:CMSInitiatingOccupancyFraction=70 -XX:+CMSParallelRemarkEnabled -XX:+DisableExplicitGC -XX:InitialHeapSize=838860800 -XX:LargePageSizeInBytes=134217728 -XX:MaxHeapSize=838860800 -XX:MaxNewSize=629145600 -XX:MaxTenuringThreshold=6 -XX:MinHeapDeltaBytes=196608 -XX:NewSize=629145600 -XX:OldPLABSize=16 -XX:OldSize=209715200 -XX:+PrintGC -XX:+PrintGCApplicationStoppedTime -XX:+PrintGCDetails -XX:+PrintGCTimeStamps -XX:ThreadStackSize=512 -XX:+UseCMSInitiatingOccupancyOnly -XX:+UseCompressedClassPointers -XX:+UseCompressedOops -XX:+UseConcMarkSweepGC -XX:+UseFastAccessorMethods -XX:+UseFastUnorderedTimeStamps -XX:+UseParNewGC
Command line:  -Xmx800m -Xms800m -Xmn600m -Xss512k -XX:PermSize=128m -XX:MaxPermSize=512m -XX:+DisableExplicitGC -XX:+UseConcMarkSweepGC -XX:+CMSParallelRemarkEnabled -XX:LargePageSizeInBytes=128m -XX:+UseFastAccessorMethods -XX:+UseCMSInitiatingOccupancyOnly -XX:CMSInitiatingOccupancyFraction=70 -verbose:gc -XX:+PrintGCApplicationStoppedTime -XX:+PrintGCTimeStamps -XX:+PrintGCDetails -Xloggc:/data/dubbo/test-project/log/jvm.log -Dfile.encoding=UTF-8 -Dheader.errorCode=true

选项 :

-flag name : Prints the name and value of the specified command-line flag.
-flag [+|-]name : enables or disables the specified Boolean command-line flag.
-flag name=value : Sets the specified command-line flag to the specified value.
-flags : Prints command-line flags passed to the JVM.
-sysprops : Prints Java system properties as name-value pairs.

4. jmap

功能为dump出堆内存情况. 先看如何使用

1
jmap -dump:format=b,file=test.dump 5234

把PID为5234的虚拟机进程堆内存情况dump到test.dump这个文件中.
如果指定live选项jmap -dump:live,for... 则表示只dumo对中活跃的对象. 注意结果文件不是人类可读的, 需要通过工具如jhat或者VisualVM这种工具来. 一般不使用jhat, 就不介绍了. 通过VisualVM 1.4.1, File -> Load, 选择文件即可.

dump是最常用的, 除此之外还支持:

  • 没有任何选项. // TODO
  • finalizerInfo: 打印F-Queue中等待Finalizer线程执行finalize方法的对象.
  • F : 当使用-dump, -histo选项时, 如果虚拟机没有反应, 可以加此选项强制. 但不能和live子选项共同使用.

-Heap

显示堆的摘要信息.

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
48
49
50
51
52
jmap -heap 5234
Attaching to process ID 5234, please wait...
Debugger attached successfully.
Server compiler detected.
JVM version is 25.121-b13

using parallel threads in the new generation.
using thread-local object allocation.
Concurrent Mark-Sweep GC

Heap Configuration:
   MinHeapFreeRatio         = 40
   MaxHeapFreeRatio         = 70
   MaxHeapSize              = 838860800 (800.0MB)
   NewSize                  = 629145600 (600.0MB)
   MaxNewSize               = 629145600 (600.0MB)
   OldSize                  = 209715200 (200.0MB)
   NewRatio                 = 2
   SurvivorRatio            = 8
   MetaspaceSize            = 21807104 (20.796875MB)
   CompressedClassSpaceSize = 1073741824 (1024.0MB)
   MaxMetaspaceSize         = 17592186044415 MB
   G1HeapRegionSize         = 0 (0.0MB)

Heap Usage:
New Generation (Eden + 1 Survivor Space):
   capacity = 566231040 (540.0MB)
   used     = 143663072 (137.00778198242188MB)
   free     = 422567968 (402.9922180175781MB)
   25.371811478226274% used
Eden Space:
   capacity = 503316480 (480.0MB)
   used     = 132438616 (126.30330657958984MB)
   free     = 370877864 (353.69669342041016MB)
   26.313188870747883% used
From Space:
   capacity = 62914560 (60.0MB)
   used     = 11224456 (10.704475402832031MB)
   free     = 51690104 (49.29552459716797MB)
   17.840792338053387% used
To Space:
   capacity = 62914560 (60.0MB)
   used     = 0 (0.0MB)
   free     = 62914560 (60.0MB)
   0.0% used
concurrent mark-sweep generation:
   capacity = 209715200 (200.0MB)
   used     = 33578192 (32.02265930175781MB)
   free     = 176137008 (167.9773406982422MB)
   16.011329650878906% used

27645 interned Strings occupying 3042984 bytes.

可以看到其中包含一些GC信息, 以及Interned String的数量和存储容量.

-histo (-histo:live)

1
2
3
4
5
6
7
8
9
10
11
12
jmap -histo 5234 >> test.histo
head test.histo

 num     #instances         #bytes  class name
----------------------------------------------
   1:          5110        9967304  [I
   2:         88631        9287640  [C
   3:         87076        2089824  java.lang.String
   4:         23722        2087536  java.lang.reflect.Method
   5:          7440        1724888  [B
   6:         45469        1455008  java.util.concurrent.ConcurrentHashMap$Node
   7:         11349        1271616  java.lang.Class

显示堆中每个类的实例数量, 和所占容量大小. 也支持live选项, 含义和-dump中一样, 也表示仅仅统计活跃的对象.

-clstats

打印堆中的ClassLoader统计. 包括名称, 活跃度, 地址, 父级ClassLoader, 加载的Class数量等信息.

5. jstack

线程信息, 支持选项

  • -F : 当VM hang住时使用此选项.
  • -l : 显示锁信息
  • -m : 如果有调用Native方法, 显示其(C/C++)栈信息()

VisualVM

VisualVM的功能实际上是几个JDK命令的集合. 一个问题是VisualVM通常不会安装在服务端, 所以需要Server开启JMX端口, 才可以被监控. 需要添加的JVM参数如下:

  • -Dcom.sun.management.jmxremote.port=9876 // 为VM实例指定JMX端口
  • -Dcom.sun.management.jmxremote.ssl=false // 禁用ssl
  • -Dcom.sun.management.jmxremote.authenticate=false // 禁用授权校验 (用户名密码)
  • -Djava.rmi.server.hostname=10.1.5.54 // 本机IP